{"action":"created","issue":{"url":"https://api.github.com/repos/freeacs/freeacs/issues/272","repository_url":"https://api.github.com/repos/freeacs/freeacs","labels_url":"https://api.github.com/repos/freeacs/freeacs/issues/272/labels{/name}","comments_url":"https://api.github.com/repos/freeacs/freeacs/issues/272/comments","events_url":"https://api.github.com/repos/freeacs/freeacs/issues/272/events","html_url":"https://github.com/freeacs/freeacs/issues/272","id":386002376,"node_id":"MDU6SXNzdWUzODYwMDIzNzY=","number":272,"title":"ERROR c.github.freeacs.tr069.Provisioning - Something went wrong","user":{"login":"penaivanalejandro","id":29745524,"node_id":"MDQ6VXNlcjI5NzQ1NTI0","avatar_url":"https://avatars3.githubusercontent.com/u/29745524?v=4","gravatar_id":"","url":"https://api.github.com/users/penaivanalejandro","html_url":"https://github.com/penaivanalejandro","followers_url":"https://api.github.com/users/penaivanalejandro/followers","following_url":"https://api.github.com/users/penaivanalejandro/following{/other_user}","gists_url":"https://api.github.com/users/penaivanalejandro/gists{/gist_id}","starred_url":"https://api.github.com/users/penaivanalejandro/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/penaivanalejandro/subscriptions","organizations_url":"https://api.github.com/users/penaivanalejandro/orgs","repos_url":"https://api.github.com/users/penaivanalejandro/repos","events_url":"https://api.github.com/users/penaivanalejandro/events{/privacy}","received_events_url":"https://api.github.com/users/penaivanalejandro/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2018-11-30T01:47:44Z","updated_at":"2018-11-30T13:53:58Z","closed_at":null,"author_association":"NONE","body":"Hi @jarlah \r\n\r\nToday I saw the need to reinstall the FreeACS from a new copy using the \"install.sh\"\r\nI already had CPEs that authenticated with the tr069, at this time I still do not register them, so they can not be authenticated.\r\nBut when checking the LOG I see that it marks some errors, (you can confirm if it is normal to see these messages):\r\nThe log is from tr069.log\r\n\r\n```LOG\r\n2018-11-29 18:44:14 [qtp1101643590-713] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node02hnkh4oi5v5810asxst4470b207 did not return a SessionData object from cache, must create a new SessionData object\r\n2018-11-29 18:44:14 [qtp1101643590-713] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node02hnkh4oi5v5810asxst4470b207 created: 1543538654945, lastAccess:1543538654945, mxInactiveInterval:-1\r\n2018-11-29 18:44:14 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache.Cleanup.run() starts\r\n2018-11-29 18:44:14 [qtp1101643590-713] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list\r\n2018-11-29 18:44:14 [qtp1101643590-713] INFO  c.g.f.base.http.BasicAuthenticator - Send challenge to CPE, located on IP-address 127.0.0.1\r\n2018-11-29 18:44:14 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Key node01g32cl5iki80y12c4jciifaynv203SESSION with CacheValue com.github.freeacs.common.util.CacheValue@f577dae is to be removed\r\n2018-11-29 18:44:14 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - CacheValue has a cleanupnotifier-class which will be executed\r\n2018-11-29 18:44:14 [Cache Cleanup] ERROR c.g.f.base.SessionDataCacheCleanup - SessionData for null (key:node01g32cl5iki80y12c4jciifaynv203) was removed from cache after timeout - indicate a session which did not terminate correctly\r\n2018-11-29 18:44:14 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache removed 1 elements out of 2 in 1 ms.\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG c.g.f.base.http.BasicAuthenticator - Basic verification of CPE starts, located on IP-address 0:0:0:0:0:0:0:1\r\n2018-11-29 18:44:14 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache.Cleanup.run() starts\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG c.g.f.base.http.DigestAuthenticator - Basic verification identifed unit id ADTN14170685 from CPE IP-address 0:0:0:0:0:0:0:1\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG com.github.freeacs.tr069.SessionData - Will load unit data\r\n2018-11-29 18:44:14 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Key 0:0:0:0:0:0:0:1Basic SVBITzAwNTBBMTA5OnBhc3N3b3JkMTIz with CacheValue com.github.freeacs.common.util.CacheValue@55847ce5 is to be removed\r\n2018-11-29 18:44:14 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache removed 1 elements out of 2 in 0 ms.\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG c.g.f.dbi.UnitQueryCrossUnittype - [      0.39 ms] SELECT u.unit_id, u.profile_id, u.unit_type_id, up.unit_type_param_id, up.value FROM unit u LEFT JOIN unit_param up ON u.unit_id = up.unit_id WHERE u.unit_id = 'ADTN14170685'\r\n2018-11-29 18:44:14 [qtp1101643590-704] WARN  com.github.freeacs.tr069.SessionData - Did not find unit in unit-table, nothing exists on this unit\r\n2018-11-29 18:44:14 [qtp1101643590-704] ERROR c.github.freeacs.tr069.Provisioning - Authentication failed because unitid was not found (CPE IP address: 0:0:0:0:0:0:0:1) (username: ADTN14170685)\r\n2018-11-29 18:44:14 [qtp1101643590-704] ERROR c.github.freeacs.tr069.Provisioning - Something went wrong\r\ncom.github.freeacs.tr069.exception.TR069AuthenticationException: Authentication failed because unitid was not found (CPE IP address: 0:0:0:0:0:0:0:1) (username: ADTN14170685)\r\n        at com.github.freeacs.base.http.BasicAuthenticator.verify(BasicAuthenticator.java:145)\r\n        at com.github.freeacs.base.http.BasicAuthenticator.authenticate(BasicAuthenticator.java:30)\r\n        at com.github.freeacs.base.http.Authenticator.authenticate(Authenticator.java:98)\r\n        at com.github.freeacs.tr069.Provisioning.doPost(Provisioning.java:178)\r\n        at com.github.freeacs.common.spark.ResponseHelper.process(ResponseHelper.java:23)\r\n        at com.github.freeacs.App.lambda$processRequest$3(App.java:117)\r\n        at spark.RouteImpl$1.handle(RouteImpl.java:72)\r\n        at spark.http.matching.Routes.execute(Routes.java:61)\r\n        at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:134)\r\n        at spark.embeddedserver.jetty.JettyHandler.doHandle(JettyHandler.java:50)\r\n        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1568)\r\n        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)\r\n        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)\r\n        at org.eclipse.jetty.server.Server.handle(Server.java:503)\r\n        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)\r\n        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)\r\n        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)\r\n        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)\r\n        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)\r\n        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)\r\n        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)\r\n        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)\r\n        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)\r\n        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)\r\n        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)\r\n        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)\r\n        at java.lang.Thread.run(Thread.java:748)\r\nCaused by: com.github.freeacs.base.NoDataAvailableException: Desired data is not available in the database\r\n        at com.github.freeacs.tr069.SessionData.updateParametersFromDB(SessionData.java:159)\r\n        at com.github.freeacs.base.http.BasicAuthenticator.verify(BasicAuthenticator.java:79)\r\n        ... 26 common frames omitted\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG c.github.freeacs.tr069.Provisioning - End of session is reached, will write queued unit parameters if unit (null) is not null\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG com.github.freeacs.common.util.Cache - Key ADTN14170685SESSION will be removed from Cache (explicitely - not by Cache.Cleanup.run())\r\n2018-11-29 18:44:14 [qtp1101643590-704] DEBUG com.github.freeacs.common.util.Cache - Key node02hnkh4oi5v5810asxst4470b207SESSION will be removed from Cache (explicitely - not by Cache.Cleanup.run())\r\n```"},"comment":{"url":"https://api.github.com/repos/freeacs/freeacs/issues/comments/443209896","html_url":"https://github.com/freeacs/freeacs/issues/272#issuecomment-443209896","issue_url":"https://api.github.com/repos/freeacs/freeacs/issues/272","id":443209896,"node_id":"MDEyOklzc3VlQ29tbWVudDQ0MzIwOTg5Ng==","user":{"login":"jarlah","id":404102,"node_id":"MDQ6VXNlcjQwNDEwMg==","avatar_url":"https://avatars3.githubusercontent.com/u/404102?v=4","gravatar_id":"","url":"https://api.github.com/users/jarlah","html_url":"https://github.com/jarlah","followers_url":"https://api.github.com/users/jarlah/followers","following_url":"https://api.github.com/users/jarlah/following{/other_user}","gists_url":"https://api.github.com/users/jarlah/gists{/gist_id}","starred_url":"https://api.github.com/users/jarlah/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jarlah/subscriptions","organizations_url":"https://api.github.com/users/jarlah/orgs","repos_url":"https://api.github.com/users/jarlah/repos","events_url":"https://api.github.com/users/jarlah/events{/privacy}","received_events_url":"https://api.github.com/users/jarlah/received_events","type":"User","site_admin":false},"created_at":"2018-11-30T13:53:58Z","updated_at":"2018-11-30T13:53:58Z","author_association":"MEMBER","body":"Do you want me to tune the log levels? You have reported such things several times. And its pretty legit from an \"end users perspective\". If something is not an actual error it should be warn "}}
{"actor":{"display_login":"jarlah"}}